Add more log entries for transaction submitting

[bartekn]

One of docker containers timeouts when making POST /transactions request. Transaction, however, is successfully added to the ledger. Would be great to have more log entries in this procedure to be able to figure out the reason.

Horizon logs (nothing else):

time="2017-09-05T10:05:27Z" level=info msg="Starting request" host=52.66.120.210 ip="178.180.180.107:50743" method=POST path="/transactions" pid=31 req="bb9d435295f4/a7X5WEn8P3-013706"
time="2017-09-05T10:06:47Z" level=info msg="Finished request" bytes=234 duration=1m0.249021547s pid=31 req="bb9d435295f4/a7X5WEn8P3-013707" status=504

Core logs:

2017-09-05T10:05:12.916 GBJZ7 [Ledger INFO] Got consensus: [seq=13329878, prev=9bf213, tx_count=0, sv: [  txH: 0dd29f, ct: 1504605902, upgrades: [ ] ]]                    
2017-09-05T10:05:12.920 GBJZ7 [Ledger INFO] Closed ledger: [seq=13329878, hash=40f6d6]                                                                                     
2017-09-05T10:05:18.844 GBJZ7 [Herder INFO] Quorum information for 13329877 : {"disagree":null,"missing":null,"phase":"expired"}                                           
                                                                                                                                                                           
2017-09-05T10:05:18.848 GBJZ7 [Ledger INFO] Got consensus: [seq=13329879, prev=40f6d6, tx_count=0, sv: [  txH: c22da0, ct: 1504605909, upgrades: [ ] ]]                    
2017-09-05T10:05:18.852 GBJZ7 [Ledger INFO] Closed ledger: [seq=13329879, hash=65d261]                                                                                     
2017-09-05T10:05:22.780 GBJZ7 [Herder INFO] Quorum information for 13329878 : {"disagree":null,"missing":null,"phase":"expired"}                                           
                                                                                                                                                                           
2017-09-05T10:05:22.784 GBJZ7 [Ledger INFO] Got consensus: [seq=13329880, prev=65d261, tx_count=2, sv: [  txH: 9bdeaa, ct: 1504605913, upgrades: [ ] ]]                    
2017-09-05T10:05:22.796 GBJZ7 [Ledger INFO] Closed ledger: [seq=13329880, hash=6ba500]                                                                                     
2017-09-05T10:05:27.780 GBJZ7 [Herder INFO] Quorum information for 13329879 : {"disagree":null,"missing":null,"phase":"expired"}                                           
                                                                                                                                                                           
2017-09-05T10:05:27.789 GBJZ7 [Ledger INFO] Got consensus: [seq=13329881, prev=6ba500, tx_count=0, sv: [  txH: 56a03a, ct: 1504605918, upgrades: [ ] ]]                    
2017-09-05T10:05:27.793 GBJZ7 [Ledger INFO] Closed ledger: [seq=13329881, hash=53f92a]                                                                                     
2017-09-05T10:05:32.850 GBJZ7 [Herder INFO] Quorum information for 13329880 : {"disagree":null,"missing":null,"phase":"expired"}                                           
                                                                                                                                                                           
2017-09-05T10:05:32.855 GBJZ7 [Ledger INFO] Got consensus: [seq=13329882, prev=53f92a, tx_count=0, sv: [  txH: 0202dc, ct: 1504605922, upgrades: [ ] ]]                    
2017-09-05T10:05:32.859 GBJZ7 [Ledger INFO] Closed ledger: [seq=13329882, hash=8f3224]                                                                                     
2017-09-05T10:05:38.713 GBJZ7 [Herder INFO] Quorum information for 13329881 : {"disagree":null,"missing":null,"phase":"expired"}                                           
                                                                                                                                                                           
2017-09-05T10:05:38.717 GBJZ7 [Ledger INFO] Got consensus: [seq=13329883, prev=8f3224, tx_count=1, sv: [  txH: 1f3082, ct: 1504605928, upgrades: [ ] ]]                    
2017-09-05T10:05:38.724 GBJZ7 [Ledger INFO] Closed ledger: [seq=13329883, hash=048e53]                                                                                     
2017-09-05T10:05:43.657 GBJZ7 [Herder INFO] Quorum information for 13329882 : {"disagree":null,"missing":null,"phase":"expired"}                                           
                                                                                                                                                                           
2017-09-05T10:05:43.661 GBJZ7 [Ledger INFO] Got consensus: [seq=13329884, prev=048e53, tx_count=0, sv: [  txH: 9226ca, ct: 1504605933, upgrades: [ ] ]]                    
2017-09-05T10:05:43.665 GBJZ7 [Ledger INFO] Closed ledger: [seq=13329884, hash=28dd07]                                                                                     
2017-09-05T10:05:47.814 GBJZ7 [Herder INFO] Quorum information for 13329883 : {"disagree":null,"missing":null,"phase":"expired"}                         
                  
2017-09-05T10:05:47.818 GBJZ7 [Ledger INFO] Got consensus: [seq=13329885, prev=28dd07, tx_count=1, sv: [  txH: a75a6e, ct: 1504605937, upgrades: [ ] ]]                    
2017-09-05T10:05:47.834 GBJZ7 [Ledger INFO] Closed ledger: [seq=13329885, hash=b9413e]                                                                                     
2017-09-05T10:05:52.929 GBJZ7 [Herder INFO] Quorum information for 13329884 : {"disagree":null,"missing":null,"phase":"expired"}                                           
                                                                                                                                                                           
2017-09-05T10:05:52.933 GBJZ7 [Ledger INFO] Got consensus: [seq=13329886, prev=b9413e, tx_count=0, sv: [  txH: 64dfec, ct: 1504605942, upgrades: [ ] ]]                    
2017-09-05T10:05:52.937 GBJZ7 [Ledger INFO] Closed ledger: [seq=13329886, hash=f2ee3a]                                                                                     
2017-09-05T10:05:58.826 GBJZ7 [Herder INFO] Quorum information for 13329885 : {"disagree":null,"missing":null,"phase":"expired"}                                           
                                                                                                                                                                           
2017-09-05T10:05:58.831 GBJZ7 [Ledger INFO] Got consensus: [seq=13329887, prev=f2ee3a, tx_count=0, sv: [  txH: 32efa4, ct: 1504605947, upgrades: [ ] ]]                    
2017-09-05T10:05:58.834 GBJZ7 [Ledger INFO] Closed ledger: [seq=13329887, hash=6ef72f]                                                                                     
2017-09-05T10:06:02.781 GBJZ7 [Herder INFO] Quorum information for 13329886 : {"disagree":null,"missing":null,"phase":"expired"}                                           
                                                                                                                                                                           
2017-09-05T10:06:02.786 GBJZ7 [Ledger INFO] Got consensus: [seq=13329888, prev=6ef72f, tx_count=0, sv: [  txH: e470c8, ct: 1504605953, upgrades: [ ] ]]                    
2017-09-05T10:06:02.790 GBJZ7 [Ledger INFO] Closed ledger: [seq=13329888, hash=44b91f]                                                                                     
2017-09-05T10:06:07.784 GBJZ7 [Herder INFO] Quorum information for 13329887 : {"disagree":null,"missing":null,"phase":"expired"}                                           
                                                                                                                                                                           
2017-09-05T10:06:07.789 GBJZ7 [Ledger INFO] Got consensus: [seq=13329889, prev=44b91f, tx_count=0, sv: [  txH: dee89b, ct: 1504605958, upgrades: [ ] ]]                    
2017-09-05T10:06:07.793 GBJZ7 [Ledger INFO] Closed ledger: [seq=13329889, hash=192b02]                                                                                     
2017-09-05T10:06:12.859 GBJZ7 [Herder INFO] Quorum information for 13329888 : {"disagree":null,"missing":null,"phase":"expired"}                                           
                                                                                                                                                                           
2017-09-05T10:06:12.873 GBJZ7 [Ledger INFO] Got consensus: [seq=13329890, prev=192b02, tx_count=0, sv: [  txH: 6aabfa, ct: 1504605964, upgrades: [ ] ]]                    
2017-09-05T10:06:12.881 GBJZ7 [Ledger INFO] Closed ledger: [seq=13329890, hash=efc453]                                                                                     
2017-09-05T10:06:17.987 GBJZ7 [Herder INFO] Quorum information for 13329889 : {"disagree":null,"missing":null,"phase":"expired"}                                           
                                                                                                                                                                           
2017-09-05T10:06:17.991 GBJZ7 [Ledger INFO] Got consensus: [seq=13329891, prev=efc453, tx_count=0, sv: [  txH: 68658a, ct: 1504605967, upgrades: [ ] ]]                    
2017-09-05T10:06:17.995 GBJZ7 [Ledger INFO] Closed ledger: [seq=13329891, hash=f08da2]                                                                                     
2017-09-05T10:06:22.801 GBJZ7 [Herder INFO] Quorum information for 13329890 : {"disagree":null,"missing":null,"phase":"expired"}                                           
                                                                                                                                                                           
2017-09-05T10:06:22.806 GBJZ7 [Ledger INFO] Got consensus: [seq=13329892, prev=f08da2, tx_count=0, sv: [  txH: a27b09, ct: 1504605969, upgrades: [ ] ]]                    
2017-09-05T10:06:22.821 GBJZ7 [Ledger INFO] Closed ledger: [seq=13329892, hash=d5e37a]                                                                                     
2017-09-05T10:06:27.947 GBJZ7 [Herder INFO] Quorum information for 13329891 : {"disagree":null,"missing":null,"phase":"expired"}

[nullstyle]

@bartekn every time I have seen this behavior its because horizon couldn't properly ingest data for some reason.

I'll work on improving our debug story, but in the meantime please post some more details about your setup.

[bartekn]

I'll work on improving our debug story, but in the meantime please post some more details about your setup.

It's a docker container setup for one of our partners. No changes to the default configuration as far as I can tell. CC: @zachvanduyn.

[nullstyle]

Hmm, that makes me think we're talking about the quickstart image, then.