cassandra-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Ryan McGuire (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (CASSANDRA-5668) NPE in net.OutputTcpConnection when tracing is enabled
Date Fri, 21 Jun 2013 15:44:21 GMT

    [ https://issues.apache.org/jira/browse/CASSANDRA-5668?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13690403#comment-13690403
] 

Ryan McGuire commented on CASSANDRA-5668:
-----------------------------------------

The NullPointerException is gone, however, I see an unexpected change in the trace after this
commit.

Prior to the patch, I do this:
{code}
$ ccm create 5668
Current cluster is now: 5668
$ ccm populate -n 2:2
$ ccm start
$ ccm node1 cqlsh
Connected to 5668 at 127.0.0.1:9160.
[cqlsh 4.0.0 | Cassandra 2.0-SNAPSHOT | CQL spec 3.1.0 | Thrift protocol 19.37.0]
Use HELP for help.
cqlsh> CREATE KEYSPACE test WITH replication = {'class': 'NetworkTopologyStrategy', 'dc1':2,
'dc2':2};
cqlsh> CREATE TABLE test.test (id int PRIMARY KEY, value text);
cqlsh> tracing on;
Now tracing requests.
cqlsh> INSERT INTO test.test (id, value) VALUES ( 5, 'asdf');

Tracing session: 5d3bdaa0-da87-11e2-9eaa-35db2404c433

 activity                                                       | timestamp    | source  
 | source_elapsed
----------------------------------------------------------------+--------------+-----------+----------------
                                             execute_cql3_query | 11:29:29,423 | 127.0.0.1
|              0
 Parsing INSERT INTO test.test (id, value) VALUES ( 5, 'asdf'); | 11:29:29,424 | 127.0.0.1
|           1082
                                             Peparing statement | 11:29:29,425 | 127.0.0.1
|           2241
                              Determining replicas for mutation | 11:29:29,425 | 127.0.0.1
|           2617
                                  Sending message to /127.0.0.2 | 11:29:29,432 | 127.0.0.1
|           9321
                                 Acquiring switchLock read lock | 11:29:29,433 | 127.0.0.1
|          10376
                                         Appending to commitlog | 11:29:29,433 | 127.0.0.1
|          10424
                                        Adding to test memtable | 11:29:29,433 | 127.0.0.1
|          10544
                                  Sending message to /127.0.0.3 | 11:29:29,435 | 127.0.0.1
|          12658
                               Message received from /127.0.0.1 | 11:29:29,436 | 127.0.0.2
|            102
                               Message received from /127.0.0.1 | 11:29:29,438 | 127.0.0.3
|            103
                        Enqueuing forwarded write to /127.0.0.4 | 11:29:29,441 | 127.0.0.3
|           3596
                                 Acquiring switchLock read lock | 11:29:29,441 | 127.0.0.3
|           3686
                                         Appending to commitlog | 11:29:29,441 | 127.0.0.3
|           3704
                                 Acquiring switchLock read lock | 11:29:29,442 | 127.0.0.2
|           5768
                                        Adding to test memtable | 11:29:29,442 | 127.0.0.3
|           3759
                                         Appending to commitlog | 11:29:29,442 | 127.0.0.2
|           5821
                                  Sending message to /127.0.0.4 | 11:29:29,442 | 127.0.0.3
|           3834
                                        Adding to test memtable | 11:29:29,442 | 127.0.0.2
|           5896
                               Enqueuing response to /127.0.0.1 | 11:29:29,442 | 127.0.0.3
|           4307
                               Enqueuing response to /127.0.0.1 | 11:29:29,443 | 127.0.0.2
|           6602
                               Message received from /127.0.0.3 | 11:29:29,444 | 127.0.0.4
|             92
                                  Sending message to /127.0.0.1 | 11:29:29,444 | 127.0.0.2
|           8037
                               Message received from /127.0.0.2 | 11:29:29,445 | 127.0.0.1
|             36
                            Processing response from /127.0.0.2 | 11:29:29,445 | 127.0.0.1
|            147
                                 Acquiring switchLock read lock | 11:29:29,452 | 127.0.0.4
|           8791
                                         Appending to commitlog | 11:29:29,452 | 127.0.0.4
|           8835
                                        Adding to test memtable | 11:29:29,452 | 127.0.0.4
|           8897
                               Enqueuing response to /127.0.0.1 | 11:29:29,453 | 127.0.0.4
|           9542
                                  Sending message to /127.0.0.1 | 11:29:29,454 | 127.0.0.4
|          10021
                               Message received from /127.0.0.4 | 11:29:29,454 | 127.0.0.1
|           9660
                            Processing response from /127.0.0.4 | 11:29:29,455 | 127.0.0.1
|           9804
                                               Request complete | 11:29:29,435 | 127.0.0.1
|          12668
{code}

That's a 2x2 multi-dc cluster with a RF of 2 in each dc. I write a single INSERT and I see
four nodes append to their commit log. All is well.

After the patch, I see this trace:

{code}
Tracing session: c3da4d00-da87-11e2-9a95-35db2404c433

 activity                                                       | timestamp    | source  
 | source_elapsed
----------------------------------------------------------------+--------------+-----------+----------------
                                             execute_cql3_query | 11:32:21,587 | 127.0.0.1
|              0
 Parsing INSERT INTO test.test (id, value) VALUES ( 5, 'asdf'); | 11:32:21,587 | 127.0.0.1
|            495
                                             Peparing statement | 11:32:21,588 | 127.0.0.1
|            962
                              Determining replicas for mutation | 11:32:21,588 | 127.0.0.1
|           1108
                                  Sending message to /127.0.0.2 | 11:32:21,590 | 127.0.0.1
|           3341
                                  Sending message to /127.0.0.3 | 11:32:21,590 | 127.0.0.1
|           3920
                               Message received from /127.0.0.1 | 11:32:21,592 | 127.0.0.2
|             91
                               Message received from /127.0.0.1 | 11:32:21,593 | 127.0.0.3
|             93
                                 Acquiring switchLock read lock | 11:32:21,593 | 127.0.0.2
|           1398
                                         Appending to commitlog | 11:32:21,593 | 127.0.0.2
|           1447
                                        Adding to test memtable | 11:32:21,593 | 127.0.0.2
|           1517
                        Enqueuing forwarded write to /127.0.0.4 | 11:32:21,594 | 127.0.0.3
|           1266
                               Enqueuing response to /127.0.0.1 | 11:32:21,594 | 127.0.0.2
|           2573
                                 Acquiring switchLock read lock | 11:32:21,594 | 127.0.0.3
|           1343
                                         Appending to commitlog | 11:32:21,594 | 127.0.0.3
|           1360
                                        Adding to test memtable | 11:32:21,594 | 127.0.0.3
|           1412
                               Enqueuing response to /127.0.0.1 | 11:32:21,595 | 127.0.0.3
|           2060
                               Message received from /127.0.0.2 | 11:32:21,595 | 127.0.0.1
|           null
                                  Sending message to /127.0.0.1 | 11:32:21,595 | 127.0.0.2
|           2850
                                  Sending message to /127.0.0.1 | 11:32:21,595 | 127.0.0.3
|           2442
                            Processing response from /127.0.0.2 | 11:32:21,595 | 127.0.0.1
|           null
                                  Sending message to /127.0.0.4 | 11:32:21,595 | 127.0.0.3
|           2442
                               Message received from /127.0.0.3 | 11:32:21,595 | 127.0.0.1
|           null
                            Processing response from /127.0.0.3 | 11:32:21,595 | 127.0.0.1
|           null
                               Message received from /127.0.0.3 | 11:32:21,597 | 127.0.0.4
|             95
                                 Acquiring switchLock read lock | 11:32:21,598 | 127.0.0.4
|           1040
                                         Appending to commitlog | 11:32:21,598 | 127.0.0.4
|           1087
                                        Adding to test memtable | 11:32:21,598 | 127.0.0.4
|           1391
                               Enqueuing response to /127.0.0.1 | 11:32:21,599 | 127.0.0.4
|           1885
                               Message received from /127.0.0.4 | 11:32:21,600 | 127.0.0.1
|           null
                                  Sending message to /127.0.0.1 | 11:32:21,600 | 127.0.0.4
|           3290
                            Processing response from /127.0.0.4 | 11:32:21,600 | 127.0.0.1
|           null
                                               Request complete | 11:32:21,592 | 127.0.0.1
|           5564
{code}

127.0.0.1 (which also happens to be the coordinator) didn't write anything to it's commit
log (according to the trace at least). Reproducible on cassandra-1.2 and trunk.


                
> NPE in net.OutputTcpConnection when tracing is enabled
> ------------------------------------------------------
>
>                 Key: CASSANDRA-5668
>                 URL: https://issues.apache.org/jira/browse/CASSANDRA-5668
>             Project: Cassandra
>          Issue Type: Bug
>    Affects Versions: 1.2.6
>            Reporter: Ryan McGuire
>            Assignee: Jonathan Ellis
>             Fix For: 1.2.6
>
>         Attachments: 5668-assert-2.txt, 5668-assert.txt, 5668-followup.txt, 5668-logs.tar.gz,
5668_npe_ddl.cql, 5668_npe_insert.cql, 5668.txt, system.log
>
>
> I get multiple NullPointerException when trying to trace INSERT statements.
> To reproduce:
> {code}
> $ ccm create -v git:trunk
> $ ccm populate -n 3
> $ ccm start
> $ ccm node1 cqlsh < 5668_npe_ddl.cql
> $ ccm node1 cqlsh < 5668_npe_insert.cql
> {code}
> And see many exceptions like this in the logs of node1:
> {code}
> ERROR [WRITE-/127.0.0.3] 2013-06-19 14:54:35,885 OutboundTcpConnection.java (line 197)
error writing to /127.0.0.3
> java.lang.NullPointerException
>         at org.apache.cassandra.net.OutboundTcpConnection.writeConnected(OutboundTcpConnection.java:182)
>         at org.apache.cassandra.net.OutboundTcpConnection.run(OutboundTcpConnection.java:144)
> {code}
> This is similar to CASSANDRA-5658 and is the reason that npe_ddl and npe_insert are separate
files.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira

Mime
View raw message